Wait for copy, avoid overlapping file events #441

BlakeGardner · 2023-12-30T23:57:52Z

Pull request

CLA

I agree that by opening a pull requests I am handing over copyright ownership
of my work contained in that pull request to the Unmanic project and the project
owner. My contribution will become licensed under the same license as the overall project.
This extends upon paragraph 11 of the Terms & Conditions stipulated in the GPL v3.0

Checklist

I have ensured that my pull request is being opened to merge into the staging branch.
I have ensured that all new python file contributions contain the correct header as
stipulated in the Contributing Docs.

Problem Statement:

During testing, it was observed that Unmanic would attempt to test/process files before they were fully written to disk. In my setup, file copying to shared/mounted drives can sometimes take a minute or two to complete.

Additionally, a single file copy was found to trigger multiple overlapping created and modified events. This caused the file monitoring system to repeatedly attempt testing the same file.

Proposed Changes in This PR:

This PR aims to address these issues by implementing the following fixes:

Event Listening Improvements: Now listens for both created and modified events to accurately capture file changes across all test scenarios.
Write-in-Progress Check: Implements a check to avoid testing a file if it is still being written to. This prevents Unmanic from processing files prematurely.
Thread Lock Usage: Utilizes a thread lock to ensure that multiple overlapping events do not lead to redundant file testing.

Before Changes

Simulate a slow file copy

rsync --inplace --bwlimit=39321 --progress ~/Movie.mkv ~/Code/unmanic-docker/library

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/Movie.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/Movie.mkv'
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/Movie.mkv'

File system copy

cp ~/Movie.mkv ~/Code/unmanic-docker/library

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/Movie.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/Movie.mkv'
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/Movie.mkv'

Directly move a file

mv Movie.mkv foo.mkv

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/foo.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/foo.mkv'

Create a file

touch hello.mkv

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/hello.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...

Modify a file

echo "hello" >> hello.mkv

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/hello.mkv'

Create a new file by copying an existing

cp foo.mkv new.mkv

INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/new.mkv'
DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/new.mkv'
INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/new.mkv'

After Changes

Simulate a slow file copy

rsync --inplace --bwlimit=39321 --progress ~/Movie.mkv ~/Code/unmanic-docker/library

2023-12-29T22:50:57:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/Movie.mkv'
2023-12-29T22:50:57:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:50:58:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:50:59:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:00:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:01:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:02:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:03:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:04:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:05:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:06:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:07:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:08:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:09:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:10:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:51:10:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Ignoring 'modified' event on file path '/library/Movie.mkv' due to other events
2023-12-29T22:51:11:DEBUG:Unmanic.Plugin.video_transcoder - File '/library/Movie.mkv' should be added to task list. Plugin found streams require processing.
2023-12-29T22:51:13:DEBUG:Unmanic.Task - [FORMATTED] - Created new task with ID: 1 for /library/Movie.mkv
2023-12-29T22:51:13:INFO:Unmanic.TaskHandler - [FORMATTED] - Adding inotify job to queue - /library/Movie.mkv

File system copy

cp ~/Movie.mkv ~/Code/unmanic-docker/library

2023-12-29T22:51:37:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/Movie.mkv'
2023-12-29T22:51:37:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:38:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/Movie.mkv' still being written to, waiting.
2023-12-29T22:51:39:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:51:39:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Ignoring 'modified' event on file path '/library/Movie.mkv' due to other events
2023-12-29T22:51:40:DEBUG:Unmanic.Plugin.video_transcoder - File '/library/Movie.mkv' should be added to task list. Plugin found streams require processing.
2023-12-29T22:51:41:INFO:Unmanic.TaskHandler - [FORMATTED] - Skipping inotify job already in the queue - /library/Movie.mkv

Directly move a file

mv Movie.mkv foo.mkv

2023-12-29T22:52:38:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/foo.mkv'
2023-12-29T22:52:38:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/foo.mkv' still being written to, waiting.
2023-12-29T22:52:39:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:52:39:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Ignoring 'modified' event on file path '/library/foo.mkv' due to other events
2023-12-29T22:52:41:DEBUG:Unmanic.Plugin.video_transcoder - File '/library/foo.mkv' should be added to task list. Plugin found streams require processing.
2023-12-29T22:52:41:DEBUG:Unmanic.Task - [FORMATTED] - Created new task with ID: 2 for /library/foo.mkv
2023-12-29T22:52:41:INFO:Unmanic.TaskHandler - [FORMATTED] - Adding inotify job to queue - /library/foo.mkv

Create a file

touch hello.mkv

2023-12-29T22:53:05:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/hello.mkv'
2023-12-29T22:53:05:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/hello.mkv' still being written to, waiting.
2023-12-29T22:53:06:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:53:09:DEBUG:Unmanic.Plugin.video_transcoder - File unable to be probed by FFProbe - '/library/hello.mkv'

Modify a file

echo "hello" >> hello.mkv

2023-12-29T22:53:27:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'modified' event on file path '/library/hello.mkv'
2023-12-29T22:53:27:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/hello.mkv' still being written to, waiting.
2023-12-29T22:53:30:DEBUG:Unmanic.Plugin.video_transcoder - File unable to be probed by FFProbe - '/library/hello.mkv'

Create a new file by copying an existing

cp foo.mkv new.mkv

2023-12-29T22:53:57:INFO:Unmanic.EventProcessor - [FORMATTED] - Detected 'created' event on file path '/library/new.mkv'
2023-12-29T22:53:57:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/new.mkv' still being written to, waiting.
2023-12-29T22:53:58:DEBUG:Unmanic.EventProcessor - [FORMATTED] - File path '/library/new.mkv' still being written to, waiting.
2023-12-29T22:53:59:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Detected event is for a directory. Ignoring...
2023-12-29T22:53:59:DEBUG:Unmanic.EventProcessor - [FORMATTED] - Ignoring 'modified' event on file path '/library/new.mkv' due to other events
2023-12-29T22:54:00:DEBUG:Unmanic.Plugin.video_transcoder - File '/library/new.mkv' should be added to task list. Plugin found streams require processing.
2023-12-29T22:54:02:DEBUG:Unmanic.Task - [FORMATTED] - Created new task with ID: 3 for /library/new.mkv
2023-12-29T22:54:02:INFO:Unmanic.TaskHandler - [FORMATTED] - Adding inotify job to queue - /library/new.mkv

…ile monitor

BlakeGardner · 2024-02-18T19:25:16Z

I am closing this PR because the solution I feel is a bit too complex for the problem I was originally trying to solve.

BlakeGardner added 5 commits December 29, 2023 12:13

Initial implementation of file copy checking before processing with f…

1b4763e

…ile monitor

Update log message in eventmonitor.py

00b7811

Added logic to prevent multiple overlapping events

fb65547

Refactor file stabilization method in eventmonitor.py

984395d

Refactor event handling logic in eventmonitor.py

41899e6

BlakeGardner changed the title ~~Feature/wait for copy~~ Wait for copy, avoid overlapping file events Dec 30, 2023

BlakeGardner added 8 commits December 31, 2023 15:35

Refactor file stabilization logic in event monitor

eb57b55

Add unit tests for file stabilization in EventMonitor class

1f0f330

Update file name in test_eventmonitor.py

7f22a6a

Update timeout parameter in _wait_for_file_stabilization method

b155891

Set default timeout to 10 minutes

f3fbd0a

Remove active file from set if file copy takes too long

8679cf0

Change exception message

f3de781

Run tests in CI

bf43041

BlakeGardner closed this Feb 18, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Wait for copy, avoid overlapping file events #441

Wait for copy, avoid overlapping file events #441

BlakeGardner commented Dec 30, 2023

BlakeGardner commented Feb 18, 2024

Wait for copy, avoid overlapping file events #441

Wait for copy, avoid overlapping file events #441

Conversation

BlakeGardner commented Dec 30, 2023

Pull request

CLA

Checklist

Problem Statement:

Proposed Changes in This PR:

Before Changes

Simulate a slow file copy

File system copy

Directly move a file

Create a file

Modify a file

Create a new file by copying an existing

After Changes

Simulate a slow file copy

File system copy

Directly move a file

Create a file

Modify a file

Create a new file by copying an existing

BlakeGardner commented Feb 18, 2024